Skip to content
New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

tracing: attempt to monomorphize is_enabled call #787

Merged
merged 3 commits into from
Jul 8, 2020

Conversation

davidbarsky
Copy link
Member

@davidbarsky davidbarsky commented Jul 7, 2020

Resolves #783.

Copy link
Member

@hawkw hawkw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This looks correct to me.

It looks like there are now a couple of dispatcher imports in the macros that can be removed, if you like:

use $crate::{callsite, dispatcher, Event, field::{Value, ValueSet}};

and
use $crate::{callsite, dispatcher, Event, field::{Value, ValueSet}};

We have to allow unused imports in the macros because some imports are only needed if the span/event has fields and may sometimes be unused depending on user input, so the compiler can't warn about these.

@davidbarsky
Copy link
Member Author

davidbarsky commented Jul 8, 2020

Good news, this worked!


Longer: I followed @matklad's steps to reproduce this issue:

$ cargo install cargo-llvm-lines
$ git clone rust-analyzer/rust-analyzer
$ cd rust-analyzer
[patching the tracing and tracing-core dependencies to this branch]
$ cd crates/ra_hir_ty
$ cargo llvm-lines

tracing_core::dispatcher::get_default is now significantly less hot, according to cargo llvm-lines:

  Lines           Copies        Function name
  -----           ------        -------------
  1202887 (100%)  46615 (100%)  (TOTAL)
    41106 (3.4%)    102 (0.2%)  alloc::raw_vec::RawVec<T,A>::grow
    31151 (2.6%)   3544 (7.6%)  core::ptr::drop_in_place
    31076 (2.6%)    539 (1.2%)  core::option::Option<T>::map
    30687 (2.6%)    317 (0.7%)  core::iter::traits::iterator::Iterator::try_fold
    27867 (2.3%)    429 (0.9%)  core::result::Result<T,E>::map_err
    25488 (2.1%)     22 (0.0%)  salsa::derived::slot::Slot<Q,MP>::read_upgrade
    24456 (2.0%)     44 (0.1%)  salsa::derived::slot::Slot<Q,MP>::probe
    17258 (1.4%)    409 (0.9%)  core::ptr::swap_nonoverlapping_one
    16742 (1.4%)     22 (0.0%)  salsa::derived::slot::Slot<Q,MP>::maybe_changed_since
    15634 (1.3%)    202 (0.4%)  alloc::vec::Vec<T>::extend_desugared

davidbarsky and others added 2 commits July 7, 2020 20:03
Co-authored-by: Eliza Weisman <eliza@buoyant.io>
@davidbarsky
Copy link
Member Author

I've removed the unneeded dispatcher imports.

Copy link
Member

@hawkw hawkw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Excellent, lgtm!

I'd love to hear from @matklad if this has a meaningful impact on rust-analyzer compile times, but I think the change is probably a good call regardless.

@@ -869,6 +869,14 @@ pub mod __macro_support {
pub type Once = tracing_core::Once;
}

#[doc(hidden)]
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We may want to consider making this public API, but I think that should be considered separately from fixing the monomorphization issue, so let's save that for another PR.

@matklad
Copy link
Contributor

matklad commented Jul 8, 2020

I observe meaningful change in cargo-llvm lines:

1687120 (100%) 52706 (100%) (TOTAL)
>>>
1587714 (100%) 51297 (100%) (TOTAL)

wall-clock time compilation impact is harder to estimate -- variance within single setup is stupidly high, and each run takes about a minute, so using proper statistic will require too much time. So, "it didn't make compilation 50% faster or slower" is all I can say.

Another thing I've noticed is that there's a bunch of calls to 14632 (0.9%) 236 (0.5%) std::sync::once::Once::call_once. (presumably from here). This shouldn't be too bad (as Once dynamizes the cold path anyway), but still I am wondering if Once is an overkill. If I am reading the code correctly, there's a mutex inside anyway, so we incur double synchronisation. It seems that Once is replaceable with Acquire/Release AtomicBool, at the cost of calling the same register more than once, which should be OK, as we lock a mutex there anyway.

@davidbarsky davidbarsky changed the title tracing: attempt to monomorphization is_enabled call tracing: attempt to monomorphize is_enabled call Jul 8, 2020
@davidbarsky
Copy link
Member Author

@matklad I'm glad you're able to observe a meaningful change in cargo-llvm lines! No worries about the compile times on your end. I've personally observed a (relatively) consistent 1-2 second change on my beefy MacBook Pro when compiling ra_hir_ty.

Another thing I've noticed is that there's a bunch of calls to 14632 (0.9%) 236 (0.5%) std::sync::once::Once::call_once. (presumably from here). This shouldn't be too bad (as Once dynamizes the cold path anyway), but still I am wondering if Once is an overkill. If I am reading the code correctly, there's a mutex inside anyway, so we incur double synchronisation. It seems that Once is replaceable with Acquire/Release AtomicBool, at the cost of calling the same register more than once, which should be OK, as we lock a mutex there anyway.

That's interesting! Since Eliza wrote that code, I'll let her comment on it, but if you're correct, I'll open another issue + PR to fix that.

@davidbarsky davidbarsky merged commit 7f60c92 into master Jul 8, 2020
@hawkw
Copy link
Member

hawkw commented Jul 8, 2020

Yeah, the Once can probably be removed with a second atomic. That path hasn't been a major focus for optimization, since it only happens once per callsite, so there's definitely room for improvement. I think this may also let us remove the vendored Once dependency for no-std targets, which would probably be the biggest benefit in my book.

hawkw added a commit that referenced this pull request Jul 8, 2020
Added

- **attributes**: Support for arbitrary expressions as fields in
  `#[instrument]` (#672)
- **attributes**: `#[instrument]` now emits a compiler warning when
  ignoring unrecognized input (#672, #786)
- Improved documentation on using `tracing` in async code (#769)

Changed

- Updated `tracing-core` dependency to 0.1.11

Fixed

- **macros**: Excessive monomorphization in macros, which could lead to
  longer compilation times (#787)
- **log**: Compiler warnings in macros when `log` or `log-always` features
  are enabled (#753)
- Compiler error when `tracing-core/std` feature is enabled but
  `tracing/std` is not (#760)

Thanks to @nagisa for contributing to this release!
hawkw added a commit that referenced this pull request Jul 8, 2020
### Added

- **attributes**: Support for arbitrary expressions as fields in
  `#[instrument]` (#672)
- **attributes**: `#[instrument]` now emits a compiler warning when
  ignoring unrecognized input (#672, #786)
- Improved documentation on using `tracing` in async code (#769)

### Changed

- Updated `tracing-core` dependency to 0.1.11

### Fixed

- **macros**: Excessive monomorphization in macros, which could lead to
  longer compilation times (#787)
- **log**: Compiler warnings in macros when `log` or `log-always` features
  are enabled (#753)
- Compiler error when `tracing-core/std` feature is enabled but
  `tracing/std` is not (#760)

Thanks to @nagisa, and everyone who contributed to the new `tracing-core`
and `tracing-attributes` versions, for contributing to this release!
# for free to join this conversation on GitHub. Already have an account? # to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

tracing_core::dispatcher is repeatedly monomorphised in the downstream crate
3 participants